900612 ESP -- SURF Center : Parsing the Raw ESP Log File Format
This page last changed on Oct 12, 2011 by kgomes.

This page is intended to provide just enough information about the ESP's raw file format so that the ESP GUI can parse it to extract time and data management entries. More complete documentation is available in MBARI's CVS repository in the file: ESP/gen2/software/esp/lib/log.rb.

The raw, real-time log is typically named real.log. The actual log file name is determined by the mode of ESP operation that generated it. A quick simulation log of a mission would be written to quick.log, for example. A real-time simulation would be written to simreal.log

All raw log files consist of a series of log entries, each of which is separated by a single ASCII linefeed (0x0a) character. Each log entry line begins with a byte that denotes its type. This simple record structure allows one to easily skip over types of log entries they do not recognize. The types of log entries that the GUI will probably want to process are timestamp, time_mark,time_increment, alias_definition and gui_data records. These log enties conform to the following grammar:

Non-terminals: (terminal symbols enclosed in <>)

digit = <0>..<9>

capital = <A>..<Z>

alpha = capital | <a>..<z>

timezone = capital[capital]?[capital]?         #Ex.  GMT, PST, PDT, Z

moniker = alpha|digit

character = <any byte except <">, <\>, <linefeed>> | <\><"> | <\><\> | <\><linefeed>

string = [character]+

actor = <">string<">|moniker|<\>

Log entries:

time_mark = <@>digit*[<.>digit+]?timezone                         #Ex.  3.14PST, .1PST, 999.01GMT, 1232498793.34PST

timestamp = <@>timezone?digit*[<.>digit+]?[</>digit*[<.>digit+]?]?    #Ex.  3.14, .1, 999.01, PST1232498793.34/100.0

time_increment = <+>digit*                             #Ex.  3, 0, 100

alias = <=>moniker?[<">string<">]?                 #Ex.  =tMAIN, =hcore, =ECan

gui_data = <`>actor?string                               #not context free, see notes below

Grammar Notes:

The actor non-terminal token in the gui_data production may be omitted if the first character of the following string is not equal to any moniker defined in a previous alias_definition. Otherwise, the  placeholder actor <\> must be inserted before the string.

An alias without a "string" deletes the alias associated with the indicated moniker

A alias missing moniker (and "string") deletes all aliases.

time_increment with no digits <+> is equivalent to +1 tic.

Example raw gui_data log entries:

`arbitrary text

`"thread_name"arbitrary text         #switched to thread_name

`\Sam is cool                              #There is an actor whose moniker is 'S', so it must be escaped

`\Saturday symphony \

on the lawn \

in the park.                                 #multiline text

Tracking Log Time:

timestamps:  Set the current log time.

  • If the timezone is specified, system is operating in real-time.
  • Real log time is Epoch seconds from Midnight 1/1/70 GMT.
  • If the timezone is omitted, system is operating in simulated time
  • Simulated log time is simply (simulated) seconds from simulation start.
  • Assume 100 Tics Per Second if tics per second is omitted

time_increments:  Increment the current real or simulated log time by specified number of tics.

time_marks: Indicate the Real-time at which the entry was generated.

  • The timezone is always specified.
  • Does not alter the current log time.

Each log entry has a "context" that consists of its log time and the actor that wrote it.

Initialize log entry context upon raw log file open:

logTime = 0

timeZone=:simulated

actors = {} #empty hash

actor = ""

ticsPerSecond = 100    #default tics per second

GetNextGuiDataText:

loop do

    case (entry type)

        when timestamp:

            logTime = epoch seconds specified

            if (zone specified)

                timeZone=zone from timestamp

            if (ticsPerSecond specified)
                 ticsPerSecond = ticsPerSecond from timestamp 

            continue;

         when time_increment:

             if increment specified

                logTime += specified increment / ticsPerSecond

             else

                logTime += 1 / ticsPerSecond

              round logTime to the nearest tic 

             continue;

         when alias:

             if (moniker present)

                if (string present)

                    actors[moniker] = string

                else

                    actors.delete moniker

              else

                  actors.clear  #delete all monikers from hash

             continue;

         when gui_data:

             c = character following <`>

             if (c == <"> )

                 actor = text between quotes

             else if (c == <\>)

                 return next character to end of entry

             else if moniker[c] exists

                 actor = moniker[c]

                 return next character to end of entry

             else

                 return c + next character to end of entry

      end  #case

end  #loop

Parsing Rules

Given the above information, here are the rules that will be applied to parsing a raw log file (.log):

Event Example Rule Used Information Parsed
Mission Start 
."Qmail"GoodNews.email "Starting w/pucks in tube 3\\n Ending Wed Oct 28 08:00:00 PDT 2009",:Subject=>"09sep29moe begun"
 
^GoodNews\\.\\S+\\s+\\\"Starting\\s+w/pucks\\s+in\\s+tube\\s+(\\d+).*Subject=>\\\"(\\S+)\\s+begun\\\".*
  1. Starting tube
  2. Mission name
Ancillary Data 
#\Can@13:19:34, 48.2V, 17.3C, 44% humidity, 14.5psia, 14.84V, 0.42A, 0.413A avg, 6.21W
CTD@13:24:25, 3.3694C, 999.623 decibars, 3.1914 S/m, 104.61%, -0.180 1/m, 0.33 ml/l, 3.0760C
ISUS@13:24:45, 24.460 uM/L no^3, -1.000 uM/L hs, 22.7800psu
  1. First it removes all newlines from the log entry and then checks to see if the entry may have ancillary data by using the pattern 
    ^Can@.*
  2. If it matches, then it takes the original log entry, splits it by newlines (I replace '\' with newlines earlier in the process) and then pattern match each line with 
    ^(\\S+)@(\\d\\d):(\\d\\d):(\\d\\d),(.*)$
    to search for time, source and the payload of the message.
  1. Source
  2. Time
  3. Payload
Process Run Start with Archive 
#pcr sampling at most 1000ml, wcr at most 1000ml
 
^(.+) sampling at most (\\d+\\.*\\d*)ml, wcr at most (\\d+\\.*\\d*)ml
  1. Process run name
  2. Process Run Target Volume
  3. Archive Target Volume
Process Run Start without Archive 
#bac wcr sampling at most 1000ml
 
^(.+) sampling at most (\\d+\\.*\\d*)ml
  1. Process run name
  2. Process Run Target Volume
Start Sample 
#t\Sampling 100.0ml
 
^Sampling\\s+(\\d+\\.*\\d*)ml.*$
 Target Volume
Stop Sample 
#t\Sampled  100.0ml
 
^Sampled\\s+(\\d+\\.*\\d*)ml.*$
 Actual Volume
DWSM Start Sample 
#t\Sample Bag inhaling 5000.0ml
 
^Sample Bag inhaling\\s+(\\d+\\.*\\d*)ml.*$
 Target Volume
DWSM Stop Sample 
#tWaiting up to 90s for Sample Bag to stabilize at 2279.4psia +/-25.0
 
^Waiting up to (\\d+)s for Sample Bag to stabilize.*$
 Nothing
Image Capture 
#"sh2"\Starlight Xpress HX9/16: 1392x1040 pixel 16-bit CCD camera
\Exposing 696x520 pixel 16-bit image for 40 seconds\
/var/log/esp/pcr11jul1500h2000ml40s.tif: TIFF Upload Complete
 Uses two patterns:
  1. One 
    ^.*Exposing\\s+(\\d+)x(\\d+)\\s+pixel\\s+(\\d+)-bit\\s+image\\s+for\\s+(\\d+\\.*\\d*)\\s+seconds(.*.tif).*$
  2. Two 
    ^(.*)\\/([a-zA-Z0-9]+)(\\d{2})([a-zA-Z]{3})(\\d{2})(\\d{2})h(\\d+)ml(\\d+)*s*\\.tif$
  1. One
    1. Image file name
  2. Two
    1. ProcessRun name
    2. Exposure Time
Errors 
."Qmail"BadNews.suppressMail "Aborted by MAIN during Intake/Exhaust Pump move",:Subject=>"Thread::Aborted in readyDWSM"
 
BadNews.\\S+\\s+\"(.*)\",:Subject=>\"(.*)\"
 Error Message

Assumptions

  1. A comment with that matches the pattern "XXXX sampling at most YYYY.Yml" indicates that an assay with the name "XXXX" is starting and will attempt to draw a water sample of YYYY.Yml.
    1. These lines can have multiple assays that are comma separated (the first entry has the phrase 'sampling' the subsequent ones do not). Here is an example: 
      #t\hab sampling at most 100.0ml, wcr at most 50.0ml

      indicates that an assay named 'hab' will run and will attempt to draw a 100.0ml water sample. That will then be followed by an assay named 'wcr' that will attempt to draw 50.0ml.

Graphical Form

The flow of a ESP log might look something like:


Attachments:
Normal Log Flow (text/xml)
Normal Log Flow (text/xml)
Normal Log Flow (text/xml)
Normal Log Flow (text/xml)
Normal Log Flow (text/xml)
Normal Log Flow (text/xml)
Normal Log Flow (text/xml)
Normal Log Flow (text/xml)
Normal Log Flow (text/xml)
Normal Log Flow (text/xml)
Normal Log Flow (text/xml)
Normal Log Flow (text/xml)
Normal Log Flow (text/xml)
Normal Log Flow (text/xml)
Normal Log Flow (text/xml)
Normal Log Flow (text/xml)
Normal Log Flow (text/xml)
Normal Log Flow (text/xml)
Normal Log Flow (text/xml)
Normal Log Flow (text/xml)
Normal Log Flow (text/xml)
Normal Log Flow (text/xml)
Document generated by Confluence on Feb 03, 2026 14:16